Skip to content

fix(db): bound the SQLite write-lock wait by time, not by attempts - #122

Merged
abrichr merged 3 commits into
mainfrom
codex/sqlite-writer-startup-contention
Aug 28, 2026
Merged

fix(db): bound the SQLite write-lock wait by time, not by attempts#122
abrichr merged 3 commits into
mainfrom
codex/sqlite-writer-startup-contention

Conversation

@abrichr

@abrichr abrichr commented Aug 28, 2026

Copy link
Copy Markdown
Member

What failed

Two hosted Windows lanes failed on 0d14af17, and it is one defect, not two.

lane run symptom
Hosted live recorder qualification (windows-latest), trial 3 33197564607 TimeoutError: ... within 30.0s; unresolved readiness: video_writer
test-windows 33197547877 attempt 1 RuntimeError: Recording child process failed: mem_writer (exit code 1) / sqlite3.OperationalError: database is locked

Both logs carry the same lines. A writer's write transaction starved for about 22 seconds and the retry policy ran out of attempts while it was still starving:

SQLite writer lock during video start time update after waiting 7.31s; retrying in 0.05s (1/2)
SQLite writer lock during video start time update after waiting 7.34s; retrying in 0.20s (2/2)
SQLite writer lock during video start time update did not clear: attempt 3 waited 7.88s and every retry is spent

One detail worth correcting: the tests-lane failure is not a startup failure. Readiness succeeded at 18:08:49. mem_writer died 25 seconds later, while screen_event_writer spent 24.6 seconds draining its screenshot backlog. The contention is whenever one writer holds the file, not only when they all start.

mem_writer does go through the retry helper — its traceback runs insert_memory_stat_insert_execute_insert_with_lock_retry. It exhausted the retries rather than missing them.

Why the policy could not work

The policy was a count of attempts with an inherited per-attempt wait. A count of attempts bounds nothing: the cost of an attempt is whatever SQLite's busy handler decides. The runners measured ~7s per attempt against a nominal 5s busy timeout, so three attempts cost ~22s — both too long to fit a 30s readiness deadline, and only three samples of a lock that was busy nearly all the time.

The fix

Bound the wait by time. _write_with_lock_retry runs against a clock: it re-enters the race for as long as SQLITE_WRITE_LOCK_BUDGET_SECONDS (20s) allows, and refuses to begin an attempt unless SQLITE_LOCK_ATTEMPT_CEILING_SECONDS (2s) remains. The total wait is therefore never more than the budget, whatever one attempt costs. The busy timeout drops 5.0s → 0.5s, turning the same budget into tens of chances rather than three. recorder.py refuses to import if the budget cannot fit its readiness deadline.

Reduce the contention as well as bound it. A live capture now keeps a write-ahead log. Under the default rollback journal every commit creates, syncs and deletes a journal file beside the capture; on Windows that churn is scanned by the filesystem filter driver, one screenshot row costs ~0.5s, and a draining writer holds the lock at nearly full duty cycle. Measured here on six concurrent writers:

journal mode median commit worst wait throughput
rollback (before) 0.72ms 2320ms 1.0x
write log + synchronous=NORMAL 0.13ms 572ms 2.5x

The write log belongs to a live capture, not to every database this package creates: create_db takes the journal mode as an argument and only the recorder passes it, so scripts/generate_synthetic_captures.py fixtures keep their exact committed bytes.

finalize_capture_database folds the log back in before a capture is verified and sealed — build_artifact_manifest inventories every regular file under the capture directory, and the -shm file is created and removed by whoever opens the database next, so a capture sealed with sidecars present would fail its own validation later. It fails loud rather than sealing one. record() also now closes the two sessions it opened and never closed.

Tests

The earlier regression test drove one writer against a lock held by one other connection. That passes against the defect. Verified: with only the old retry policy restored, 13 of 15 tests in this file still pass — including that one.

The new test_concurrent_writers_all_survive_a_busy_write_lock starts the real memory_writer, performance_stats_writer and video write_events bodies together against one database whose lock is already held. It fails against the replaced policy, because three attempts is three chances.

Two more measure rather than assert the bound:

  • test_one_locked_attempt_costs_less_than_the_declared_ceiling times a real attempt with the production busy timeout against the declared ceiling.
  • test_the_total_wait_never_runs_past_the_declared_budget times the whole helper against the declared budget, and fails both when it overruns and when it gives up early.

test_a_write_logged_capture_verifies_and_seals covers the seal path without a display or input permissions.

Full suite: 721 passed, 33 skipped. ruff clean.

Note for the reviewer

test-windows skips on PRs and runs only on push to main, so this PR going green says nothing about Windows. The Windows evidence is the post-merge run plus the three-trial qualification gate.

Separately: run 33197547877 now reads success because attempt 2 re-ran the failed job on the same commit with no code change. triggering_actor is abrichr, and this repo has no automatic re-run in any workflow — so a person or a peer session did it. Any green on test-windows at or before 0d14af17 is worthless.

abrichr and others added 3 commits August 28, 2026 14:48
Two hosted Windows lanes failed on 0d14af1 for one reason. A writer's write
transaction starved for about twenty-two seconds and the retry policy ran out
of attempts while it was still starving.

In the qualification lane video_writer spent 22.8s on three attempts at its
video start-time update, never announced readiness, and failed the thirty-second
startup deadline. In the tests lane mem_writer spent 21.9s on three attempts
while the screen writer drained its screenshot backlog, exhausted them, and
exited 1. Readiness had already succeeded there: the contention is not confined
to startup, it is whenever one writer holds the file.

The policy was a count of attempts with an inherited per-attempt wait, and a
count of attempts bounds nothing. The runners measured one attempt at about
seven seconds against a nominal five-second busy timeout, so three attempts
cost twenty-two seconds -- too long to fit the readiness deadline, and only
three samples of a lock that was busy nearly all the time.

Spend a declared time budget instead. _write_with_lock_retry now runs against a
clock: it re-enters the race for as long as SQLITE_WRITE_LOCK_BUDGET_SECONDS
allows and stops as soon as too little budget remains to finish another
attempt, so the total wait is never more than the budget whatever one attempt
costs underneath. The busy timeout drops to 0.5s, which turns the same budget
into tens of chances at the lock rather than three. recorder.py refuses to
import if the budget cannot fit inside its readiness deadline.

Reduce the contention as well as bound it. A live capture now keeps a
write-ahead log. Under the default rollback journal every commit creates, syncs
and deletes a journal file beside the capture; on Windows that churn is scanned
by the filesystem filter driver, one screenshot row costs about half a second,
and a writer draining a backlog holds the single write lock at nearly full duty
cycle. A write log appends instead, and readers stop blocking writers. Measured
here on six concurrent writers, it cut median commit latency from 0.72ms to
0.13ms and the worst wait from 2.3s to 0.57s.

The write log is a property of a live capture, not of every database this
package creates: create_db takes the journal mode as an argument, and only the
recorder passes it. A fixture built by scripts/generate_synthetic_captures.py
has one writer and its bytes are unchanged.

finalize_capture_database folds the log back into the file before a capture is
verified and sealed. build_artifact_manifest inventories every regular file
under the capture directory, and the shared-memory file is created and removed
by whoever opens the database next, so a capture sealed with its sidecars
present would fail its own validation later. It fails loud rather than sealing
one. record() also now closes the two sessions it opened and never closed,
which otherwise held the file open past the end of the recording.

tests/test_db_lock_retry.py gains the shape that was missing. The earlier
regression test drove one writer against a lock held by one other connection,
which passes against the defect. The new test starts the real memory,
performance-stats and video writer bodies together against one database whose
lock is already held, which is what production does, and it fails against the
replaced policy because three attempts is three chances. Two more tests measure
rather than assert the bound: one times a real attempt against the declared
attempt ceiling, the other times the whole helper against the declared budget
and fails both when it overruns and when it gives up early.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@abrichr
abrichr merged commit 55658f9 into main Aug 28, 2026
14 checks passed
@abrichr
abrichr deleted the codex/sqlite-writer-startup-contention branch August 28, 2026 18:54
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant